![AWS X-Ray SDK for PythonでOSError: [Errno 90] Message too longのエラーが出たので調査/対応してみた](https://devio2023-media.developers.io/wp-content/uploads/2019/05/aws-lambda.png)
AWS X-Ray SDK for PythonでOSError: [Errno 90] Message too longのエラーが出たので調査/対応してみた
MAD事業部@大阪の岩田です。先日Lambdaのエラーを監視&通知しているSNSトピックからOSError: [Errno 90] Message too long
というエラーが発生したという通知が飛んできました。このエラーの原因を調査&対応したので対応方法についてご紹介します。
概要
エラーが発生していたのは夜間バッチ処理のStep Functionsから起動されるLambdaです。RDBに保存されたデータを集計し、集計後のデータを再度RDBに書き戻すような処理を実行しています。このLambdaのログにFailed to send entity to Daemon.
というエラーメッセージが出力され、これがエラー検知の仕組みに引っかかっていました。
ログに出力されていたスタックトレースはこんな感じでした
Traceback (most recent call last): File \"/opt/python/aws_xray_sdk/core/emitters/udp_emitter.py\", line 41, in send_entity self._send_data(message) File \"/opt/python/aws_xray_sdk/core/emitters/udp_emitter.py\", line 63, in _send_data self._socket.sendto(data.encode('utf-8'), (self._ip, self._port)) OSError: [Errno 90] Message too long"}
どうもUDPのパケットサイズ上限に抵触しているような気配がします
ググってみる
とりあえずエラーメッセージを元にググってみたところ、以下の情報がヒットしました。
- "failed to send data to X-Ray daemon." -> "Message too long"
- Tracer: "failed to send data to X-Ray daemon"
対象Lambdaにxray_recorder.configure(streaming_threshold=0)
を追加し、トレースデータをバッチ送信せずサブセグメントごとに個別送信すればメッセージサイズの上限に引っかからずに済みそうです。AWS Lambda Powertools (Python)でも上記の対応が導入されていました。
is_cold_start = True logger = logging.getLogger(__name__) # Set the streaming threshold to 0 on the default recorder to force sending # subsegments individually, rather than batching them. # See https://github.com/awslabs/aws-lambda-powertools-python/issues/283 aws_xray_sdk.core.xray_recorder.configure(streaming_threshold=0)
https://github.com/awslabs/aws-lambda-powertools-python/pull/284/files
ということでLambdaのコードを修正し、翌日のバッチ処理で様子を見ることにしました。
streaming_thresholdを0にしても改善しなかった
これで無事に問題が解決しただろう...と思ったのですが翌日もエラー通知のメールが飛んできました。なぜ...と思い、もう少し詳細を調査することにしました。
AWS X-Ray SDK for Pythonのコードを確認するとエラーが発生している箇所の前後は以下のようなコードになっていました。
def send_entity(self, entity): """ Serializes a segment/subsegment and sends it to the X-Ray daemon over UDP. By default it doesn't retry on failures. :param entity: a trace entity to send to the X-Ray daemon """ try: message = "%s%s%s" % (PROTOCOL_HEADER, PROTOCOL_DELIMITER, entity.serialize()) log.debug("sending: %s to %s:%s." % (message, self._ip, self._port)) self._send_data(message) except Exception: log.exception("Failed to send entity to Daemon.")
self._send_data(message)
の前にlog.debug
が埋め込まれているので、DEBUGレベルのログを出力すればどういう情報を送信しようとしてエラーになっているのかが分かりそうです。対象のLambdaに以下のコードを追加しました。
logging.getLogger('aws_xray_sdk').setLevel(logging.DEBUG)
これでAWS X-Ray SDK for PythonからはDEBUGレベルのログまで出力されるようになります。この状態でLambadを実行するとエラーログの直前には以下のようなログが出力されていました。
"sending: {\"format\":\"json\",\"version\":1}\n{\"id\": \"266d5575e6d637ee\", \"name\": \"hogehoge.abcdefghij.ap-northeast-1.rds.amazonaws.com\", \"start_time\": 1639993720.4766362, \"parent_id\": \"8a347a31f141d234\", \"in_progress\": false, \"trace_id\": \"1-61c05176-3afe80c6161eb00720cc563c\", \"type\": \"subsegment\", \"namespace\": \"remote\", \"sql\": {\"url\": \"mysql+pymysql://db_user@hogehoge.abcdefghij.ap-northeast-1.rds.amazonaws.com/db?charset=utf8&program_name=hoge-function\", \"user\": \"db_user\", \"database_type\": \"mysql\", \"driver_version\": \"pymysql\", \"database_version\": \"5.7.33\", \"sanitized_query\": \"INSERT INTO tab(col1, col2) VALUES(%(col1_m1)s,%(col2_m1)s),(%(col1_m2)s,%(col2_m2)s),.... \"}, \"end_time\": 1639993720.4975338} to 169.254.79.129:2000."
集計後のデータをまとめてINSERTするSQLが長すぎてメッセージサイズに引っかかっていたようです。MySQL側の制限に抵触しないように一定件数でINSERT文を分割実行するような考慮は実装していましたが、MySQLの上限よりもはるかに早くX-Ray SDK(というよりはLambda実行環境のUDPパケットサイズ上限)の上限に抵触してしまったようです。
X-Ray SDKからSQL文の送信を停止する
原因が分かったので対策を検討します。SQL文が長過ぎてエラーになっているので、対策としては
- SQL文が長くならないようにINSERT文の実行単位をさらに小さくする
- SQL文の記録を停止する
のいずれかになりそうです。今回実行しているLambdaではINSERT文がX-Rayに記録されなくても特に支障は無いので、SQL文の送信を停止して対応することにしました。Lambdaのコードに
xray_recorder.configure(stream_sql=False)
を追加することで、X-Ray SDKからのSQL文送信を停止できます。
この対応を入れたところ翌日からはエラー通知のメールが飛んで来ないようになりました。無事解決です。
まとめ
X-Rayデーモンへのトレースデータ送信はUDPを使ってるんですね。なるほど。
SQL文が長くなり過ぎてMySQLの制限に抵触しないように注意はしていましたが、X-Rayのトレースデータ送信でエラーになるのは盲点でした。RDBを扱うシステムでは注意しておきたいですね。